ANR分析

ANR问题分析

在Android开发的bug调试过程中，ANR算是最让开发者头疼的一种情况，一方面是因为导致ANR发生的原因很多，另一个方面ANR不像一般的BUG可能又会非常明显异常堆栈，最重要的一方面也是因为大多数ANR发生时并没有什么规律可寻，因此也不好重现。本篇笔者将对ANR做一个全面的介绍，并为排除ANR提出可行的方案。

ANR的检测机制

Android对于ANR有多个方面的监测机制：

Input事件5秒内未处理超时导致ANR
Service运行在应用程序的主线程，如果Service的执行时间超过20秒，则会引发ANR。
BroadCast事件处理中如果执行时间超过10秒导致ANR

本篇不打算分析Anroid系统在以上的几种检测机制的实现过程。我们只需要知道ANR监测机制实际上是对应用程序主线程的要求，要求主线成必须在限定的时间内，完成对操作的响应;否则，就可以认为应用程序主线程失去响应能力。

ANR 日志

CPU日志

ANR发生的进程
ANR发生的原因
CPU负载
各进程的CPU使用率
CPU使用汇总

首先发生ANR时，系统会对该异常做出响应，并在data/anr/traces.txt生成相应的信息。这些信息打印了发生ANR时相关进程堆栈状态，我们正是基于此来分析发生ANR发生的原因。下面我们看一组Anr发生时的logcat日志

E/SensorsHal(  406): poll() failed (Interrupted system call)
E/ActivityManager(  406): ANR in at.smarthome.hcomm  
E/ActivityManager(  406): PID: 584
E/ActivityManager(  406): Reason: Broadcast of Intent { act=android.intent.action.TIME_TICK flg=0x50000014 (has extras) }
E/ActivityManager(  406): Load: 2.04 / 0.73 / 0.26
E/ActivityManager(  406): CPU usage from 5849ms to 0ms ago:
E/ActivityManager(  406):   8.7% 725/wpa_supplicant: 0.1% user + 8.5% kernel / faults: 1 minor
E/ActivityManager(  406):   1.5% 406/system_server: 0.6% user + 0.8% kernel / faults: 118 minor
E/ActivityManager(  406):   1.5% 812/RTW_CMD_THREAD: 0% user + 1.5% kernel
E/ActivityManager(  406):   1% 950/com.tt.ttt: 0.3% user + 0.6% kernel
E/ActivityManager(  406):   0.1% 584/at.xxx.xxx: 0.1% user + 0% kernel / faults: 29 minor
E/ActivityManager(  406):   0.1% 20/kconsole: 0% user + 0.1% kernel
E/ActivityManager(  406):   0% 25/irq/58-rk30-adc: 0% user + 0% kernel
E/ActivityManager(  406):   0.1% 28/fb-vsync: 0% user + 0.1% kernel
E/ActivityManager(  406):   0.1% 30/cfinteractive: 0% user + 0.1% kernel
E/ActivityManager(  406):   0.1% 462/com.android.systemui: 0.1% user + 0% kernel / faults: 1 minor
E/ActivityManager(  406):   0.1% 640/xx.yyyy.yyyy: 0% user + 0.1% kernel / faults: 12 minor
E/ActivityManager(  406): 3.1% TOTAL: 0.5% user + 2.5% kernel + 0% softirq
E/ActivityManager(  406): CPU usage from 1858ms to 2367ms later:
E/ActivityManager(  406):   3.8% 406/system_server: 0% user + 3.8% kernel
E/ActivityManager(  406):     5.7% 421/ActivityManager: 1.9% user + 3.8% kernel
E/ActivityManager(  406):   1.4% 97/surfaceflinger: 0% user + 1.4% kernel
E/ActivityManager(  406):   1.6% 640/yy.yyyy.yyyy: 1.6% user + 0% kernel / faults: 1 minor
E/ActivityManager(  406): 0.5% TOTAL: 0% user + 0.5% kernel

从日志我们可以看到发生anr时的进程信息（包名和PID），以及发生ANR的原因，比如第一个的REASON表示在处理TIME_TICK广播消息超时。意思是TIME_TICK是一个串行广播消息，在PID为584的进程中，执行BroadcastReceiver.onReceive()方法已经超过10秒，Load关键字表示了最近1分钟，5分钟，15分钟内CPU的负载分别是 2.04 / 0.73 / 0.26，最近1分钟内的负载为2.04，可以理解为CPU最近1分钟平均有2.04个任务处理，这样的CPU负载并不算高，那么发生ANR的具体原因应该不是因为CPU负载过重引起，可能是由于等待IO引起的。CPU关键字后面的是发生ANR时各进程的CPU负载统计

经验法则

如果iowait较高，则倾向考虑是由io读写阻塞导致的
CPU负载较高，考虑程序中是否哪里由做频繁的运算，比如ACTION_MOVE中做一些耗时的运算或者引起频繁GC导致CPU一直被占用这时候再响应Input是就会出现ANR。
内存泄漏导致的内存不足问题，此时Dalvik线程为VMWAIT状态。
死锁导致的ANR

参考

https://duanqz.github.io/2015-10-12-ANR-Analysis